マルチAZ配置のAmazon RDS for SQL Serverのエンジンメジャーバージョンアップに3時間以上かかった時に取得できたRDSイベントを公開します
2024.03.13エンジンメジャーバージョンアップを実施した
こんにちは！AWS事業本部のおつまみです。
みなさん、マルチAZ配置のAmazon RDS for SQL Serverのエンジンメジャーバージョンアップを実施したことはありますか？私はあります。
先日こちらの作業を立ち会った際、事前検証の倍以上時間がかかるといった事態が発生していました。
今回その時にどのくらい時間がかかったのか、およびその時のRDSイベントログを公開したいと思います。
また、なぜそれほど時間がかかったのかRDSイベントログから考察してみました。
いきなり結論
- メジャーバージョンアップ時に、3時間以上の時間を要した。
- RDSイベントログをみる限り、以下の処理に時間を要した。
- アップグレード前のスナップショットを取得(79分)
- RDSのリカバリ処理（49分）
- スナップショットの取得時間はワークロードの実行有無に依存する。
- RDSのリカバリ処理はRDSの基盤となるハードウェアに障害が発生した場合に届く通知である。
前提
エンジンバージョンアップ時の挙動
RDSがエンジンバージョンアップ時にどのような挙動をするかおさらいしましょう。
RDSの自動バックアップが有効な場合、バージョンアップグレード処理は以下のようなステップとなります。
- アップグレード前のスナップショットを取得
- DBインスタンスをアップグレード
- アップグレード後のスナップショットを取得
シングルAZ/マルチAZ構成に関わらず同じ挙動となりますが、マルチAZ構成の場合はスタンバイのRDSからスナップショットが取得されます。
図にするとこのようなイメージです。
RDSイベントログ
通常時
同じインスタンスクラスのRDSでエンジンバージョンアップを実行した際、下記のログが出力されていました。
最初の実行時間を00:00:00として、時系列に変換しています。
| 時間 | イベントID | メッセージ | 備考 |
|---|---|---|---|
| 00:00:00 | RDS-EVENT-0001 | Backing up DB instance | |
| 00:03:00 | RDS-EVENT-0002 | Finished DB Instance backup | |
| 00:03:00 | RDS-EVENT-0026 | Applying off-line patches to DB instance | DB インスタンスのオフライン メンテナンス実行中。DB インスタンスは現在利用できません。 |
| 00:11:00 | RDS-EVENT-0004 | DB instance shutdown | |
| 00:21:00 | RDS-EVENT-0004 | DB instance shutdown | |
| 00:21:00 | RDS-EVENT-0006 | DB instance restarted | |
| 00:41:00 | RDS-EVENT-0004 | DB instance shutdown | |
| 00:41:00 | RDS-EVENT-0006 | DB instance restarted | |
| 00:47:00 | RDS-EVENT-0013 | Multi-AZ instance failover started. | |
| 00:47:00 | RDS-EVENT-0049 | Multi-AZ instance failover completed | |
| 00:54:00 | RDS-EVENT-0004 | DB instance shutdown | |
| 00:55:00 | RDS-EVENT-0023 | Emergent Snapshot Request: Databases found to still be awaiting snapshot. | |
| 01:00:00 | RDS-EVENT-0023 | Emergent Snapshot Request: Databases found to still be awaiting snapshot. | |
| 01:00:00 | RDS-EVENT-0004 | DB instance shutdown | |
| 01:00:00 | RDS-EVENT-0006 | DB instance restarted | |
| 01:05:00 | RDS-EVENT-0023 | Emergent Snapshot Request: Databases found to still be awaiting snapshot. | 手動バックアップがリクエストされましたが、現在、Amazon RDS は DB スナップショットの作成中です。Amazon RDS で DB スナップショットの作成が完了した後で、リクエストをもう一度送信してください。 |
| 01:06:00 | RDS-EVENT-0027 | Finished applying off-line patches to DB instance | DB インスタンスのオフラインメンテナンスが完了しました。現在、DB インスタンスは利用できます。 |
| 01:07:00 | RDS-EVENT-0078 | Monitoring Interval changed to 60 | 拡張モニタリングの設定が変更されました。 |
| 01:07:00 | N/A | Performance Insights has been enabled | |
| 01:07:00 | RDS-EVENT-0001 | Backing up DB instance | |
| 01:11:00 | RDS-EVENT-0002 | Finished DB Instance backup | |
| 01:14:00 | RDS-EVENT-0092 | Finished updating DB parameter group |
結果、約1時間14分でバージョンアップが完了しました。
なお今回本番変更するRDSのスナップショットを取得することができなかったため、上記は同じインスタンスクラスのRDSを使用し、検証しています。
本番変更時のRDSイベントログ
本番変更時では、下記のログが出力されていました。
想定より時間がかかった処理には備考欄に△、事前検証時に確認できなかったイベントログには備考欄に☆をつけています。
| 時間 | イベントID | イベント説明 | 備考 |
|---|---|---|---|
| 00:00:00 | RDS-EVENT-0001 | Backing up DB instance | |
| 01:19:00 | RDS-EVENT-0002 | Finished DB Instance backup | △ |
| 01:19:00 | RDS-EVENT-0026 | Applying off-line patches to DB instance | |
| 01:28:00 | RDS-EVENT-0004 | DB instance shutdown | |
| 01:41:00 | RDS-EVENT-0020 | Recovery of the DB instance has started. Recovery time will vary with the amount of data to recover. | ☆ |
| 01:55:00 | RDS-EVENT-0020 | Recovery of the DB instance has started. Recovery time will vary with the amount of data to recover. | ☆ |
| 02:05:00 | RDS-EVENT-0020 | Recovery of the DB instance is complete. | ☆ |
| 02:30:00 | RDS-EVENT-0004 | DB instance shutdown | |
| 02:31:00 | RDS-EVENT-0006 | DB instance restarted | |
| 02:34:00 | RDS-EVENT-0065 | Recovered from partial failover | |
| 02:34:00 | RDS-EVENT-0013 | Multi-AZ instance failover started. | |
| 02:34:00 | RDS-EVENT-0049 | Multi-AZ instance failover completed | |
| 02:41:00 | RDS-EVENT-0004 | DB instance shutdown | |
| 02:42:00 | N/A | Emergent Snapshot Request: Databases found to still be awaiting snapshot. | |
| 02:47:00 | N/A | Emergent Snapshot Request: Databases found to still be awaiting snapshot. | |
| 02:52:00 | N/A | Emergent Snapshot Request: Databases found to still be awaiting snapshot. | |
| 02:53:00 | RDS-EVENT-0004 | DB instance shutdown | |
| 02:53:00 | RDS-EVENT-0006 | DB instance restarted | |
| 02:56:00 | RDS-EVENT-0027 | Finished applying off-line patches to DB instance | |
| 02:57:00 | N/A | Emergent Snapshot Request: Databases found to still be awaiting snapshot. | |
| 02:57:00 | RDS-EVENT-0006 | DB instance restarted | |
| 02:58:00 | RDS-EVENT-0006 | DB instance restarted | |
| 03:02:00 | N/A | Emergent Snapshot Request: Databases found to still be awaiting snapshot. | |
| 03:02:00 | RDS-EVENT-0092 | Finished updating DB parameter group | |
| 03:04:00 | RDS-EVENT-0001 | Backing up DB instance | |
| 03:09:00 | RDS-EVENT-0002 | Finished DB Instance backup |
結果、約3時間9分でバージョンアップが完了しました。
想定より時間がかかった処理および、事前検証時に確認できなかったイベントログはこちらです。
- アップグレード前のスナップショットを取得(79分)
- RDSのリカバリ処理（49分）
ここから、なぜ時間を要したのか考察してみます。
考察
アップグレード前のスナップショットを取得
まず、アップグレード前のスナップショットを取得に79分の時間を要していました。
こちら調査したところ、スナップショットの取得時間はワークロードの実行有無に依存するとのことでした。
バックアップ時間を長くするその他の要因には、次のようなものがあります。 - CPU とメモリの可用性 - ディスク I/O - データベースアクティビティ - データベースのサイズ （引用：RDS for SQL Server のバックアップにかかる時間を確認する | AWS re:Post）
つまり、本番環境のスナップショット取得には、上記の要因が絡み、大幅に時間が延長された可能性が考えられます。
一方、事前検証は本番環境のスナップショットから復元した環境で実施していました。
そのため、実際にワークロードが実行されておらず、本番環境と比較し、短時間で完了したということが考えられます。
RDSのリカバリ処理
つづいて、RDSのリカバリ処理に49分の時間を要していました。
出力されていたRecovery of the DB instance has started. Recovery time will vary with the amount of data to recover.は、RDSの基盤となるハードウェアに障害が発生した場合に届く通知のようです。
イベント「Recovery of the DB instance has started. Recovery time will vary with the amount of data to be recovered. (DB インスタンスの復旧がスタートされました。復旧時間は、復旧するデータの量に応じて変わります。) 」これは、インスタンスのハードウェアが復旧中であることを意味します。Amazon RDS の復旧は、新しい Amazon Elastic Compute Cloud (Amazon EC2) ホストに移行して、ハードウェアを交換することによって行われます。 （引用：Amazon RDS と Amazon Aurora のパフォーマンスとイベントの可視性を高める）
今回該当時間帯に、 AWS Health Dashboard でRDSの基盤となるハードウェアへの障害報告は出ていませんでした。
そのため、運悪くハードウェア障害が発生したことが考えられます。
考察は以上となります。
さいごに
今回は、マルチAZ配置Amazon RDS for SQL Serverのエンジンメジャーバージョンアップに3時間以上かかった時に取得できたRDSイベントを公開してみました。
本番環境のスナップショットから復元した環境と本番環境では、実際のワークロード状況に応じて、変更時間に差異が発生することがわかりました。
どのくらい時間がかかるは実際にワークロードを実行し、全く同じ条件にしないと予測できないということですね。
今後変更を予定されている方は注意してください！
最後までお読みいただきありがとうございました！
どなたかのお役に立てれば幸いです。
以上、おつまみ（＠AWS11077）でした！
参考
Amazon RDS のイベントカテゴリとイベントメッセージ - Amazon Relational Database Service
RDS for SQL Server のバックアップにかかる時間を確認する | AWS re:Post
